-
Notifications
You must be signed in to change notification settings - Fork 4.5k
stats/opentelemetry: record retry attempts from clientStream #8342
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: master
Are you sure you want to change the base?
stats/opentelemetry: record retry attempts from clientStream #8342
Conversation
Codecov ReportAll modified and coverable lines are covered by tests ✅
Additional details and impacted files@@ Coverage Diff @@
## master #8342 +/- ##
==========================================
- Coverage 82.41% 82.20% -0.22%
==========================================
Files 419 419
Lines 42025 42065 +40
==========================================
- Hits 34637 34580 -57
- Misses 5944 6013 +69
- Partials 1444 1472 +28
🚀 New features to boost your workflow:
|
stream.go
Outdated
@@ -430,6 +432,7 @@ func (cs *clientStream) newAttemptLocked(isTransparent bool) (*csAttempt, error) | |||
IsServerStream: cs.desc.ServerStreams, | |||
IsTransparentRetryAttempt: isTransparent, | |||
} | |||
ctx = context.WithValue(ctx, clientStreamKey{}, cs.numRetries) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
as @dfawley suggested, we should just compute the retry attempts within otel interceptors #8299 (comment). While incrementing in trace.go, we should just skip if transparent retry is true. Re-using cs.numRetries
is not advisable.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thanks! Updated to compute retry attempts in the otel interceptor (TagRPC) and no longer using cs.numRetries
stats/opentelemetry/trace.go
Outdated
// Note: Go always added Client and FailFast attributes even though they are not | ||
// defined by the OpenCensus gRPC spec. Thus, they are unimportant for | ||
// correctness. | ||
span.SetAttributes( | ||
attribute.Bool("Client", rs.Client), | ||
attribute.Bool("FailFast", rs.FailFast), | ||
attribute.Int64("previous-rpc-attempts", int64(ai.previousRPCAttempts)), | ||
attribute.Int64("retry-attempts", int64(atomic.LoadUint32(&ai.explicitRetryCount))), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
we shouldn't be adding a new attribute. previous-rpc-attempts
should be enough to depict retries. If > 0, that means there were retries. You should be doing the increment here if transparent-retry is false.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
See https://github.com/grpc/proposal/blob/master/A72-open-telemetry-tracing.md#tracing-information. We should be confined to attributes defined here.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
@@ -121,6 +122,10 @@ func (h *clientTracingHandler) HandleConn(context.Context, stats.ConnStats) {} | |||
// TagRPC implements per RPC attempt context management for traces. | |||
func (h *clientTracingHandler) TagRPC(ctx context.Context, info *stats.RPCTagInfo) context.Context { | |||
ctx, ai := getOrCreateRPCAttemptInfo(ctx) | |||
if ai.previousRPCAttempts > 0 { | |||
atomic.AddUint32(&ai.explicitRetryCount, 1) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Retry attempts need to be counted by storing data in the context in a per-call interceptor. If you store it in the attemptInfo, it will get reset every attempt.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
if ai.previousRPCAttempts > 0 { | ||
atomic.AddUint32(&ai.explicitRetryCount, 1) | ||
} | ||
atomic.AddUint32(&ai.previousRPCAttempts, 1) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
you can maintain single attribute. Either previousRPCAttempts or explicitRetryCount. Why do we need both?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thanks. I've removed explicitRetryCount and now use only previousRPCAttempts to track retries.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I remember we had separate tests for retries. This change should only affect that test. This change shouldn't affect tests which are doing only single attempt.
// TagRPC implements per RPC attempt context management for traces. | ||
func (h *clientTracingHandler) TagRPC(ctx context.Context, info *stats.RPCTagInfo) context.Context { | ||
ctx, ai := getOrCreateRPCAttemptInfo(ctx) | ||
var counter *int32 | ||
if val := ctx.Value(retryCountKey{}); val != nil { | ||
counter = val.(*int32) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
this again seems wrong. We should create the retry count key in the interceptor call which is per RPC. TagRPC is for per attempt. Here we should only retrieve the current retry count value (if needed)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thanks for the clarification. I've updated the code accordingly — the retry count key is now created within the interceptor to ensure it's per-RPC
stats/opentelemetry/trace.go
Outdated
if !rs.IsTransparentRetryAttempt { | ||
if val := ai.ctx.Value(retryCountKey{}); val != nil { | ||
// Atomic increment and get new value | ||
retryCount = uint32(atomic.AddInt32(val.(*int32), 1)) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
this value needs to be set back to context somewhere? otherwise we have lost the count.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
stats/opentelemetry/trace.go
Outdated
// Note: Go always added Client and FailFast attributes even though they are not | ||
// defined by the OpenCensus gRPC spec. Thus, they are unimportant for | ||
// correctness. | ||
span.SetAttributes( | ||
attribute.Bool("Client", rs.Client), | ||
attribute.Bool("FailFast", rs.FailFast), | ||
attribute.Int64("previous-rpc-attempts", int64(ai.previousRPCAttempts)), | ||
attribute.Int64("previous-rpc-attempts", int64(retryCount)), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Please note as per https://github.com/grpc/proposal/blob/master/A72-open-telemetry-tracing.md#tracing-information, previousRPCAttempts is the count of retries before current, so we should set here the existing retryCount value (before incrementing it). However, we should increment retry count after and set back to context for future.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
stats/opentelemetry/e2e_test.go
Outdated
@@ -928,7 +928,7 @@ func (s) TestMetricsAndTracesOptionEnabled(t *testing.T) { | |||
}, | |||
{ | |||
Key: "previous-rpc-attempts", | |||
Value: attribute.IntValue(0), | |||
Value: attribute.IntValue(1), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It should be correctly 0 because it counts previous rpc attempts which means before current so for the first attempt it should be 0.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@vinothkumarr227 have you tested this to ensure its working correctly? I was under impression that TestTraceSpan_WithRetriesAndNameResolutionDelay will need changes for expected values. I think its not working as expected because you are not setting the count back to ctx after incrementing.
@@ -48,6 +48,8 @@ func (h *clientTracingHandler) initializeTraces() { | |||
} | |||
|
|||
func (h *clientTracingHandler) unaryInterceptor(ctx context.Context, method string, req, reply any, cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error { | |||
ci := &callInfo{numRetries: 0} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
both these operations can be done in getOrCreateCallInfo? That we set call info in ctx only once
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
@@ -58,6 +60,8 @@ func (h *clientTracingHandler) unaryInterceptor(ctx context.Context, method stri | |||
} | |||
|
|||
func (h *clientTracingHandler) streamInterceptor(ctx context.Context, desc *grpc.StreamDesc, cc *grpc.ClientConn, method string, streamer grpc.Streamer, opts ...grpc.CallOption) (grpc.ClientStream, error) { | |||
ci := &callInfo{numRetries: 0} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
same here about moving both to getOrCreateCallInfo
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
stats/opentelemetry/opentelemetry.go
Outdated
@@ -179,6 +179,8 @@ type callInfo struct { | |||
// nameResolutionEventAdded is set when the resolver delay trace event | |||
// is added. Prevents duplicate events, since it is reported per-attempt. | |||
nameResolutionEventAdded atomic.Bool | |||
// numRetries holds the count of non-transparent retry attempts. | |||
numRetries int32 |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
better to declare it as atomic and do regular operation for it otherwise you need to explicitly mention that this field need to be accessed atomically. Former is better IMO.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
stats/opentelemetry/trace.go
Outdated
// retry. | ||
if !rs.IsTransparentRetryAttempt { | ||
if ci, ok := getRetryCount(ai.ctx); ok { | ||
atomic.AddInt32(&ci.numRetries, 1) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
As called out before, we need to set this back to context.
Also, it might be more clear if we name this field as well to previousRPCAttempts because at the time of retrieving its not accounting the current retry.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thanks for the clarification. I've updated the code accordingly
stats/opentelemetry/opentelemetry.go
Outdated
return context.WithValue(ctx, retryCountKey{}, ci) | ||
} | ||
|
||
// getRetryCount retrieves the retry count tracking struct from the context. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
no need of docstring since the function is simple enough to understand.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
stats/opentelemetry/opentelemetry.go
Outdated
} | ||
|
||
// getRetryCount retrieves the retry count tracking struct from the context. | ||
func getRetryCount(ctx context.Context) (*callInfo, bool) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
nit: its preferred to avoid get prefix in these situations https://g3doc.corp.google.com/go/g3doc/style/decisions.md?cl=head#getters
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thanks for the clarification. I've updated the code accordingly
stats/opentelemetry/e2e_test.go
Outdated
@@ -1708,6 +1710,32 @@ func verifyTrace(t *testing.T, spans tracetest.SpanStubs, want traceSpanInfo) { | |||
} | |||
} | |||
|
|||
func verifyPreviousRPCAttempts(t *testing.T, spans tracetest.SpanStubs) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
why this needs to be a separate function? We are just verifying the previous-rpc-attempts which is already being compared. We shouldn't need this.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
@@ -81,6 +81,7 @@ func getOrCreateCallInfo(ctx context.Context, cc *grpc.ClientConn, method string | |||
} | |||
ctx = setCallInfo(ctx, ci) | |||
} | |||
ctx = setRetryCount(ctx, ci) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Its weird that we are maintaining the ci instance in 2 separate keys. We should either just hold the retry count in the retry count key or keep one key value pair of callInfo with field tracking retryCount. Either way its fine but since you have already added retryCount to callInfo, we should only setCallInfo and retryCount should just be another field in that.
Also, let's rename the field previousRPCAttempts
since that's what we are updating it to.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
ci = &callInfo{
target: cc.CanonicalTarget(),
method: determineMethod(method, opts...),
previousRPCAttempts: 0
}
ctx = setCallInfo(ctx, ci)
Then you can remove line 84
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
stats/opentelemetry/e2e_test.go
Outdated
observedSpans[val] = append(observedSpans[val], span.Name) | ||
for _, wantAttr := range want.attributes { | ||
for _, attr := range span.Attributes { | ||
fmt.Println("Span Name", span.Name) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
why we need these print statements?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
stats/opentelemetry/opentelemetry.go
Outdated
@@ -179,8 +179,8 @@ type callInfo struct { | |||
// nameResolutionEventAdded is set when the resolver delay trace event | |||
// is added. Prevents duplicate events, since it is reported per-attempt. | |||
nameResolutionEventAdded atomic.Bool | |||
// numRetries holds the count of non-transparent retry attempts. | |||
numRetries int32 | |||
// previousRPCAttempts holds the count of non-transparent retry attempts. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
// previousRPCAttempts holds the count of RPC attempts that have happened before current attempt. Transparent // retries are excluded.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
stats/opentelemetry/opentelemetry.go
Outdated
@@ -219,8 +219,7 @@ func setRetryCount(ctx context.Context, ci *callInfo) context.Context { | |||
return context.WithValue(ctx, retryCountKey{}, ci) | |||
} | |||
|
|||
// getRetryCount retrieves the retry count tracking struct from the context. | |||
func getRetryCount(ctx context.Context) (*callInfo, bool) { | |||
func retryCount(ctx context.Context) (*callInfo, bool) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
we won't need it anymore as we already have for callInfo
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
stats/opentelemetry/trace.go
Outdated
atomic.AddInt32(&ci.numRetries, 1) | ||
if ci, ok := retryCount(ai.ctx); ok { | ||
ci.previousRPCAttempts.Add(1) | ||
ai.ctx = setRetryCount(ai.ctx, ci) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
now, we will call setCallInfo here
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
@@ -118,9 +118,15 @@ func (h *clientTracingHandler) TagConn(ctx context.Context, _ *stats.ConnTagInfo | |||
// HandleConn exists to satisfy stats.Handler for tracing. | |||
func (h *clientTracingHandler) HandleConn(context.Context, stats.ConnStats) {} | |||
|
|||
type retryCountKey struct{} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
won't be needed if we are maintaining within callInfo
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
// TagRPC implements per RPC attempt context management for traces. | ||
func (h *clientTracingHandler) TagRPC(ctx context.Context, info *stats.RPCTagInfo) context.Context { | ||
ctx, ai := getOrCreateRPCAttemptInfo(ctx) | ||
if ci, ok := retryCount(ctx); ok { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
this will call getOrCreateCallInfo
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done
if ci, ok := retryCount(ctx); ok { | ||
ai.previousRPCAttempts = uint32(ci.previousRPCAttempts.Load()) | ||
} | ||
ai.ctx = ctx |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
why set context here? This will happen later anyway?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
We need to explicitly set ai.ctx = ctx here because populateSpan later uses ai.ctx to retrieve and update callInfo. If we skip this assignment, ai.ctx remains nil, leading to a nil pointer.
stats/opentelemetry/e2e_test.go
Outdated
if diff := cmp.Diff(want.events, span.Events, cmpopts.IgnoreFields(trace.Event{}, "Time")); diff != "" { | ||
t.Errorf("Span event mismatch for %q (kind: %s) (-want +got):\n%s", | ||
want.name, want.spanKind, diff) | ||
if len(want.events) > 0 { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
why do we have to make any change to this method? If we declare the wantSpanInfos in the caller test like here https://github.com/grpc/grpc-go/blob/master/stats/opentelemetry/e2e_test.go#L1082-L1240 we shouldn't need to change anything here.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I’ve added new test cases for TestRetrySpans_UnaryCallAttributes
stats/opentelemetry/e2e_test.go
Outdated
@@ -1677,31 +1678,58 @@ func (s) TestTraceSpan_WithRetriesAndNameResolutionDelay(t *testing.T) { | |||
t.Fatalf("%s call failed: %v", tt.name, err) | |||
} | |||
|
|||
wantSpanInfo := traceSpanInfo{ | |||
methodName := strings.TrimPrefix(tt.spanName, "Sent.") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
this is not very easy to understand. For tests its usually better to have static declarations for expected values instead of forming at runtime. Can we do similar to how its done in other tests https://github.com/grpc/grpc-go/blob/master/stats/opentelemetry/e2e_test.go#L1082-L1240. Then you don't need to make changes in verifyTrace
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
if we use static declarations for expected values, we encounter issues when the LB policy provides a new pick value (reference). That’s why we’re using verifyTrace and focusing the test specifically on the name resolution delay event. For that reason, I’ve tested both the previous-rpc-attempts and the name-resolution events.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I’ve added new test cases for TestRetrySpans_UnaryCallAttributes
Fixes: #8299
RELEASE NOTES:
grpc.previous-rpc-attempts
) are now recorded as span attributes for non-transparent client retries.